nit: this variable name makes the switch statements below confusing, can we change it to "finalDecision" or something like that?

OK, I will give the type a more descriptive name.

I am not sure how I missed that descr1, descr2 interface{} is being passed around; that is really weird and hard to understand, and neither the comment nor the name of the parameters helps me understand what they are supposed to be such that passing them as an interface{} makes sense. Can we fix this in a followup? Worst case, the caller can package their log identity in a single string. I think it is reasonable for the caller to pass some printable request identifier. There may also already be such a thing hidden in the context.

Note that we already have a trace system that prints out times when requests are slow, it uses a number to identify the request so you can see which trace line goes to which request. I think we should probably reuse that number. I think it is buried in ctx somewhere.

I am not sure I understand the idea regarding the trace system. If the logging output gets just one message about a request, and that message shows a number and not the RequestInfo and User details, then it will not be helpful. Is the number only for the source code, and somehow the details appear in the log message? Or does something trigger an additional log message that associates the number with details?

I really do not want to go creating long strings that will not get logged for every request.

BTW, what is weird and hard to understand about this? It is passing two opaque values that get logged to explain what the request is.

The goal is not to log a request identifier but rather enough details of the request that a reader of log messages can understand which request is involved.

Since there's (potentially) multiple messages logged about a single request, they'll be interspersed in the logs with gajillions of unrelated messages. So, a reader of the logs needs a simple way to show all messages related to the request of interest to them.

We already have a similar problem when showing which aspects of a request were slow, in the trace system. There, we print in one message the request details, and in many messages timing information. To keep the log spam down, traces only begin to print once some part of the request has been sufficiently slow.

Now, we have the additional problem of making sure that the relevant additional request information gets logged when appropriate. It actually makes the log lines harder to read and searches less precise to print out the request description with every related log line rather than printing out a request ID and the relevant information once.

(I say all this as someone who occasionally does high-stakes spelunking in apiserver logs.)

I complain about the variable names since it seems really strange to know that you need two pieces of data, but not know what they are enough to give them a name or a type. It makes this code difficult to understand apart from its usage.

I actually think logging at V(6) isn't going to be super helpful in real life, V(6) is an impractical amount of data. I'd like to find a way to log < 1 message per request, so that we can have the logs on at V2, to give operators some chance at retroactively understanding what the system was doing. Even something rudimentary like occasionally logging the trace IDs of requests that are stuck in hot queues would be useful.

We also probably want to make requests that spend time in the queue automatically trigger the trace system; maybe instead we can adjust the top-level per-request line (which is V3) to also log the amount of time spent in queues.

Here's an example use of the trace code: